﻿//++
//
// Copyright (c) Microsoft Corporation.  All rights reserved.
//
// Module Name:
//
//  LoggerTest.cs
//    
// Abstract:
//
//  Unit tests for the Logger class.
//  
//--

using System;
using System.Diagnostics;
using System.Collections.Generic;
using System.Globalization;
using System.Text;
using System.Threading;

using Microsoft.VisualStudio.TestTools.UnitTesting;

namespace Microsoft.OfficeCommunicationsServer.Applications.Common.UnitTests
{
    internal delegate void WriteOperationalLogDelegate(int eventId, string format, params object[] args);
    internal delegate void WriteDiagnosticLogDelegate(string category, Context context, string format, params object[] args);

    /// <summary>
    ///This is a test class for LoggerTest and is intended to contain all LoggerTest Unit Tests.
    ///</summary>
    [TestClass()]
    public class LoggerTest
    {
        private const string _source = "Enhanced Reminders Unit Tests";
        private const string _logName = "Enhanced Reminders Unit Tests Log";
        private const string _etwSessionName = "Enhanced Reminders Unit Tests ETW Session";
        private const string _extendedProperties = "<test>Extended Properties</test>";

        private static EtwTraceController _etwController = new EtwTraceController(_etwSessionName);
        private static EtwTraceConsumer _etwConsumer = new EtwTraceConsumer(_etwSessionName);

        private AutoResetEvent _wait;
        private List<EventReadEventArgs> _results = new List<EventReadEventArgs>();
        private int _numberExpectedTraceEvents;

        /// <summary>
        /// A mock Context used to test Logger.FormatMessageForEtw.
        /// </summary>
        private class TestLoggerContext : Context
        {
            public override string ExtendedPropertiesToXmlString()
            {
                return _extendedProperties;
            }
        }

        // Initialize ETW resources prior to each test.
        [TestInitialize()]
        public void MyTestInitialize()
        {
            _wait = new AutoResetEvent(false);
            _etwConsumer.EventRead += EtwConsumer_EventRead;
        }

        // Cleanup ETW resources after each test.
        [TestCleanup()]
        public void MyTestCleanup()
        {
            _wait.Close();
            _results.Clear();
            _etwConsumer.EventRead -= EtwConsumer_EventRead;
        }

        // Creates an event log and starts the ETW session for the LoggerTest unit tests.
        [ClassInitialize()]
        public static void MyClassInitialize(TestContext testContext)
        {
            if (EventLog.SourceExists(_source))
            {
                EventLog.DeleteEventSource(_source);
            }

            // Create the event log to be used by these tests
            EventLog.CreateEventSource(_source, _logName);

            // Need to wait for the source to be registered
            for (int i = 0; i < 20 && !EventLog.SourceExists(_source); i++)
            {
                System.Threading.Thread.Sleep(1000);
            }

            Assert.IsTrue(EventLog.SourceExists(_source), "EventLog.SourceExists(_source)");

            // Ensure that the ETW session used by these tests isn't already started
            EtwTraceController.StopTrace(_etwSessionName);

            // Start the ETW session used by these tests
            _etwController.StartTrace();
            _etwController.EnableTrace(true);

            // Open the ETW session and start waiting for trace events
            _etwConsumer.OpenTrace();
            _etwConsumer.ProcessTraceAsync();
        }
        
        // Cleans up the event log and ETW session used by the LoggerTest unit tests.
        [ClassCleanup()]
        public static void MyClassCleanup()
        {
            if (EventLog.SourceExists(_source))
            {
                EventLog.DeleteEventSource(_source);
            }

            // This causes the ProcessTrace thread in the ETW consumer to complete which in turn closes the ETW session
            _etwController.StopTrace(); 
        }

        /// <summary>
        /// Tests that Logger.FormatMessageForEtw formats the message correctly.
        /// </summary>
        [TestMethod()]
        public void LoggerTestsFormatMessage()
        {
            // Initialize the logger 
            Logger.Initialize(_source, TraceLogLevel.All, true);

            string expectedCategory = "Test category";
            Context expectedContext = Context.Global;
            string expectedMessage = "Test message";
            Exception expectedError = null;

            // Check that the context and error message aren't logged
            string actualFormattedMessage = Logger_Accessor.FormatMessageForEtw(expectedCategory, expectedContext, expectedMessage, expectedError);
            Assert.AreEqual<string>(
                Logger_Accessor.SourceStartTag + _source + Logger_Accessor.SourceEndTag + 
                Logger_Accessor.CategoryStartTag + expectedCategory + Logger_Accessor.CatgeoryEndTag + 
                Logger_Accessor.MessageStartTag + expectedMessage + Logger_Accessor.MessageEndTag, 
                actualFormattedMessage);

            expectedCategory = null;
            expectedMessage = "Test message";
            expectedError = null;

            // Check that the category isn't logged
            actualFormattedMessage = Logger_Accessor.FormatMessageForEtw(expectedCategory, expectedContext, expectedMessage, expectedError);
            Assert.AreEqual<string>(
                Logger_Accessor.SourceStartTag + _source + Logger_Accessor.SourceEndTag +
                Logger_Accessor.MessageStartTag + expectedMessage + Logger_Accessor.MessageEndTag, 
                actualFormattedMessage);

            expectedCategory = null;
            expectedMessage = "Test message";
            expectedError = new ArgumentException("Test exception");

            // Check that the exception is logged
            actualFormattedMessage = Logger_Accessor.FormatMessageForEtw(expectedCategory, expectedContext, expectedMessage, expectedError);
            Assert.AreEqual<string>(
                Logger_Accessor.SourceStartTag + _source + Logger_Accessor.SourceEndTag +
                Logger_Accessor.MessageStartTag + expectedMessage + Logger_Accessor.MessageEndTag +
                Logger_Accessor.ErrorStartTag + "<![CDATA[" + expectedError + "]]>" + Logger_Accessor.ErrorEndTag,
                actualFormattedMessage);

            expectedCategory = null;
            expectedContext = new TestLoggerContext();
            expectedMessage = "Test message";
            expectedError = null;

            // Check that the context is logged
            actualFormattedMessage = Logger_Accessor.FormatMessageForEtw(expectedCategory, expectedContext, expectedMessage, expectedError);
            Assert.AreEqual<string>(
                Logger_Accessor.SourceStartTag + _source + Logger_Accessor.SourceEndTag +
                _extendedProperties +
                Logger_Accessor.MessageStartTag + expectedMessage + Logger_Accessor.MessageEndTag, 
                actualFormattedMessage);

            Logger.Close();
        }

        /// <summary>
        /// Test that Logger.WriteOperationalError writes the appropriate information to the event log and ETW. 
        /// </summary>
        [TestMethod()]
        public void LoggerTestWriteOperationalError()
        {
            WriteOpertionalLog(new WriteOperationalLogDelegate(Logger.WriteOperationalError), EventLogEntryType.Error, 1);
        }

        /// <summary>
        /// Test that Logger.WriteOperationalWarning writes the appropriate information to the event log and ETW. 
        /// </summary>
        [TestMethod()]
        public void LoggerTestWriteOperationalWarning()
        {
            WriteOpertionalLog(new WriteOperationalLogDelegate(Logger.WriteOperationalWarning), EventLogEntryType.Warning, 1);
        }

        /// <summary>
        /// Test that Logger.WriteOperationalInformation writes the appropriate information to the event log and ETW. 
        /// </summary>
        [TestMethod()]
        public void LoggerTestWriteOperationalInformation()
        {
            WriteOpertionalLog(new WriteOperationalLogDelegate(Logger.WriteOperationalInformation), EventLogEntryType.Information, 1);
        }

        /// <summary>
        /// Test that Logger.WriteOperationalInformation writes the appropriate information to the event log and ETW when called multiple times. 
        /// </summary> 
        [TestMethod()]
        public void LoggerTestMultipleWriteOperationalInformation()
        {
            WriteOpertionalLog(new WriteOperationalLogDelegate(Logger.WriteOperationalInformation), EventLogEntryType.Information, 3);
        }

        /// <summary>
        /// Test that Logger.WriteTraceError writes the appropriate information to ETW. 
        /// </summary>
        [TestMethod()]
        public void LoggerTestWriteDiagnosticError()
        {
            WriteDiagnosticLog(new WriteDiagnosticLogDelegate(Logger.WriteTraceError), LogEntryType.Error, 1);
        }

        /// <summary>
        /// Test that Logger.WriteTraceWarning writes the appropriate information to ETW. 
        /// </summary>
        [TestMethod()]
        public void LoggerTestWriteDiagnosticWarning()
        {
            WriteDiagnosticLog(new WriteDiagnosticLogDelegate(Logger.WriteTraceWarning), LogEntryType.Warning, 1);
        }

        /// <summary>
        /// Test that Logger.WriteTraceInformation writes the appropriate information to ETW. 
        /// </summary>
        [TestMethod()]
        public void LoggerTestWriteDiagnosticInformation()
        {
            WriteDiagnosticLog(new WriteDiagnosticLogDelegate(Logger.WriteTraceInformation), LogEntryType.Information, 1);
        }

        /// <summary>
        /// Test that Logger.WriteTraceVerbose writes the appropriate information to ETW. 
        /// </summary>
        [TestMethod()]
        public void LoggerTestWriteDiagnosticVerbose()
        {
            WriteDiagnosticLog(new WriteDiagnosticLogDelegate(Logger.WriteTraceVerbose), LogEntryType.Verbose, 1);
        }

        /// <summary>
        /// Test that Logger.WriteTraceInformation writes the appropriate information to ETW when called multiple times. 
        /// </summary> 
        [TestMethod()]
        public void LoggerTestMultipleWriteDiagnosticInformation()
        {
            WriteDiagnosticLog(new WriteDiagnosticLogDelegate(Logger.WriteTraceInformation), LogEntryType.Information, 3);
        }

        /// <summary>
        /// Test that only Logger.WriteTraceError writes anything to ETW when the TraceLogLevel is set to TraceLogLevel.Errors.
        /// </summary>
        [TestMethod()]
        public void TestWriteDiagnosticLogLevel()
        {
            // The event log source should already exist
            Assert.IsTrue(EventLog.SourceExists(_source), "EventLog.SourceExists(_source)");

            // Information to be written
            string expectedMessage = "Test Message";
            string expectedCategory = "Test Category";
            Context expectedContext = new Context();

            // Only one trace log should be written
            _numberExpectedTraceEvents = 1;

            // Initialize the logger 
            Logger.Initialize(_source, TraceLogLevel.Errors, true);

            // Write the logs
            Logger.WriteTraceVerbose(expectedCategory, expectedContext, expectedMessage);
            Logger.WriteTraceInformation(expectedCategory, expectedContext, expectedMessage);
            Logger.WriteTraceWarning(expectedCategory, expectedContext, expectedMessage);
            Logger.WriteTraceError(expectedCategory, expectedContext, expectedMessage);

            // Close logging
            Logger.Close();

            // Verify that the expected information was written to ETW
            CheckDiagnosticResults(expectedCategory, expectedMessage, expectedContext, LogEntryType.Error, 1);
        }

        /// <summary>
        /// Calls the specified method to write to the operational logs and verifies the expected information is written to both 
        /// the event log and ETW.
        /// </summary>
        /// <param name="writeDelegate">Method that writes to the operational logs</param>
        /// <param name="eventLogEntryType">Type of operational log</param>
        /// <param name="repeat">Number of times to write the log</param>
        private void WriteOpertionalLog(WriteOperationalLogDelegate writeDelegate, EventLogEntryType eventLogEntryType, int repeat)
        {
            // The event log source should already exist
            Assert.IsTrue(EventLog.SourceExists(_source), "EventLog.SourceExists(_source)");

            // Open the event log and make sure it is empty
            EventLog eventLog = new EventLog(_logName);
            eventLog.Source = _source;
            eventLog.Clear();

            // Information to be written
            string expectedMessage = "Test Message";
            int expectedEventId = 0;

            // There should be as many trace log events as "write" requests
            _numberExpectedTraceEvents = repeat;

            // Initialize the logger
            Logger.Initialize(_source, TraceLogLevel.All, true);

            // Write the logs
            for (int i = 0; i < repeat; i++)
            {
                writeDelegate.Invoke(expectedEventId, expectedMessage);
            }
            
            // Close logging
            Logger.Close();

            // Check that the event log contains the correct number of entries
            Assert.AreEqual<int>(repeat, eventLog.Entries.Count, "Unexpected number of entries");

            // Check each event log entry matches expectations
            foreach (EventLogEntry entry in eventLog.Entries)
            {
                Assert.AreEqual<string>(expectedMessage, entry.Message, "Unexpected message");
                Assert.AreEqual<long>((long)expectedEventId, entry.InstanceId, "Unexpected event ID");
                Assert.AreEqual<EventLogEntryType>(eventLogEntryType, entry.EntryType, "Unexpected log entry type");
            }

            // Clear the event log
            eventLog.Clear();

            // Verify that the expected information was written to ETW
            CheckDiagnosticResults(null, expectedMessage, Context.Global, LogEntryFromEventLogEntry(eventLogEntryType), repeat);
        }

        /// <summary>
        /// Calls the specified method to write to the diagnostic logs and verifies the expected information is written to ETW.
        /// </summary>
        /// <param name="writeDelegate">Method that writes to the diagnostic logs</param>
        /// <param name="logEntryType">Type of diagnostic log</param>
        /// <param name="repeat">Number of times to write the log</param>
        private void WriteDiagnosticLog(WriteDiagnosticLogDelegate writeDelegate, LogEntryType logEntryType, int repeat)
        {
            // The event log source should already exist
            Assert.IsTrue(EventLog.SourceExists(_source), "EventLog.SourceExists(_source)");
            
            // Information to be written
            string expectedMessage = "Test Message";
            string expectedCategory = "Test Category";
            Context expectedContext = new Context();

            // There should be as many trace log events as "write" requests
            _numberExpectedTraceEvents = repeat;

            // Initialize the logger 
            Logger.Initialize(_source, TraceLogLevel.All, true);

            // Write the logs
            for (int i = 0; i < repeat; i++)
            {
                writeDelegate.Invoke(expectedCategory, expectedContext, expectedMessage);
            }

            // Close logging
            Logger.Close();

            // Verify that the expected information was written to ETW
            CheckDiagnosticResults(expectedCategory, expectedMessage, expectedContext, logEntryType, repeat);
        }

        /// <summary>
        /// Verifies that the specified expected information was written to ETW.
        /// </summary>
        /// <param name="expectedCategory">Expected category</param>
        /// <param name="expectedMessage">Expected trace message</param>
        /// <param name="expectedContext">Expected context</param>
        /// <param name="logEntryType">Expected type of log entry</param>
        /// <param name="repeat">Expected number of trace events</param>
        private void CheckDiagnosticResults(string expectedCategory, string expectedMessage, Context expectedContext, LogEntryType logEntryType, int repeat)
        {
            _etwController.FlushTrace();

            Microsoft.EnhancedReminders.UnitTests.Helpers.WaitOne<AutoResetEvent>(_wait, "Timed out waiting for trace events");

            Assert.AreEqual<int>(repeat, _results.Count, "Unexpected number of trace events");

            // Check each trace event matches expectations
            foreach (EventReadEventArgs args in _results)
            {
                string expectedFormattedMessage = Logger_Accessor.FormatMessageForEtw(expectedCategory, expectedContext, expectedMessage, null);
                Assert.AreEqual<Guid>(expectedContext.ActivityId, args.EventGuid, "Unexpected trace event guid");
                Assert.AreEqual<string>(expectedFormattedMessage, args.EventString, "Unexpected trace event message");
                Assert.AreEqual<int>((int)logEntryType, args.Level, "Unexpected trace event level");
            }
        }

        /// <summary>
        /// Converts the specified EventLogEntryType into the corresponding LogEntryType. 
        /// </summary>
        /// <param name="entryType">EventLogEntryType to be converted</param>
        /// <returns>
        /// The corresponding LogEntryType; or LogEntryType.Verbose if there is an error.
        /// </returns>
        private static LogEntryType LogEntryFromEventLogEntry(EventLogEntryType entryType)
        {
            LogEntryType logEntryType = LogEntryType.Verbose;

            switch (entryType)
            {
                case EventLogEntryType.Error:
                    logEntryType = LogEntryType.Error;
                    break;

                case EventLogEntryType.Warning:
                    logEntryType = LogEntryType.Warning;
                    break;

                case EventLogEntryType.Information:
                    logEntryType = LogEntryType.Information;
                    break;

                default:
                    Debug.Fail(String.Format(CultureInfo.InvariantCulture, "Unexpected EventLogEntryType: {0}", entryType));
                    break;
            }

            return logEntryType;
        }

        /// <summary>
        /// Handles read events from the ETW consumer.
        /// </summary>
        /// <param name="sender">Not used</param>
        /// <param name="e">Contains the information in the corresponding trace event</param>
        private void EtwConsumer_EventRead(object sender, EventReadEventArgs e)
        {
            // Add the event args to the list of results so that the results can be verified on the VSTest thread once all 
            // the expected events have been read
            _results.Add(e);

            _numberExpectedTraceEvents--;

            if (_numberExpectedTraceEvents == 0)
            {
                // The expected number of events has been read, so wake up the VSTest thread
                _wait.Set();
            }
        }
    }
}
